Skip to content

Per-tool-call/reasoning-step latency breakdown (detail.latency_breakdown) - #1758

Merged
Tomkess merged 11 commits into
masterfrom
feat/tool-call-latency-breakdown
Aug 25, 2026
Merged

Per-tool-call/reasoning-step latency breakdown (detail.latency_breakdown)#1758
Tomkess merged 11 commits into
masterfrom
feat/tool-call-latency-breakdown

Conversation

@Tomkess

@Tomkess Tomkess commented Aug 24, 2026

Copy link
Copy Markdown
Contributor

Summary

Motivating question from a colleague reviewing eval latency reports: "we report 117s for alert creation, can we break that down by task?" Neither avg_latency_s (one number for the whole turn) nor the .reasoning.json sidecar (prose, no timing) could answer that.

  • Timestamps each SSE tool-call and reasoning-step event as it streams in (ToolCallEvent.call_ts/result_ts/index, ReasoningStepEvent.ts/index — client-observed receipt time, not a server measurement).
  • build_latency_breakdown() merges tool calls and reasoning steps into one chronological timeline and returns an ordered sequence of steps (seq, kind, name, index, duration_s) — not a dict aggregated by name, so a tool called twice or two reasoning steps sharing a title stay distinguishable and in real execution order.
  • index is the step's position in its own source list (same position as in ChatResult.reasoning_steps and, downstream, the .reasoning.json sidecar's ordered list) — lets a human or script look up the full record (tool args/result, or the full reasoning paragraph) without a separate merge tool.
  • Reasoning labels are the bolded title only (**Title**\n\n...Title), not the full paragraph — otherwise every entry is an unreadable wall of text.
  • best_run_latency_s: for K>1, avg_latency_s is a cross-run mean while detail.latency_breakdown only ever describes the single best-ranked run — comparing the breakdown's sum against the mean is not a valid "% explained" check. This is the run's own latency, computed alongside the same best-run tracking already needed for the fix below.
  • Fixes a real bug this surfaced: core/runner.py's single-shot path took reasoning_steps from whichever run executed last, but best_detail from whichever run ranked best — for K>1 these could be different runs, so the sidecar and detail.latency_breakdown could each describe a different attempt with no way to tell. Both now come from the same run.
  • Wired into all 9 currently-enabled test kinds (verified against gdc-mic-ai-evaluation's data/test_kinds.yaml): visualization, vis_agentic, agentic_alert_skill, agentic_metric_skill, agentic_guardrail, agentic_conversation, general_question, guardrail, search_tool. The 4 multi-turn agentic kinds re-offset both timestamps and indices across turns (each turn's own SSE stream restarts near 0).

Live verification (not just unit tests)

Ran real eval questions through gdc-mic-ai-evaluation end-to-end at each step of this branch, with actual result-file writing:

  • visualization/K=1: coverage went from 40% (tool-only) → 92-97% (tool+reasoning) of avg_latency_s explained, once reasoning attribution landed.
  • visualization/K=3 real run: confirmed avg_latency_s (129.30) ≠ best_run_latency_s (118.22) — the bug the last commit fixes, observed live, not just asserted in a test.
  • search_tool/K=3: confirmed the new fields populate correctly for a newly-wired single-shot kind.
  • Directly reproduced real parallel tool-call batches (multiple search_objects/create_adhoc_visualization calls sharing identical call_ts) twice live — both resolved 100% of calls via callId, zero collisions, confirming the SSE callId-matching logic handles concurrency correctly.

Test plan

  • uv run pytest packages/gooddata-eval/tests/ — 454-465 passed across each commit (count varies as tests were added), same 9 pre-existing failures as master (missing openai extra + one unrelated registry test) throughout, zero new failures at any point.
  • ruff check — clean at every commit.
  • Live runs against a real GoodData workspace (see above), with real result-file output inspected by hand.

Note: commits 1bc4a38e/13ed3c8b are a temporary debug-logging commit and its revert (used to directly verify the callId-matching live-verification claim above) — net zero diff, kept for transparency on how that claim was checked rather than squashed away.

🤖 Generated with Claude Code

Tomkess added 10 commits August 24, 2026 12:24
Per-tool-call wall time (call receipt to result receipt) was invisible --
avg_latency_s is one number for the whole turn, and the reasoning sidecar
has section titles but no timing. Stamps call_ts/result_ts on each
ToolCallEvent as it streams in and adds build_latency_breakdown() to
sum wall time by tool name, so a slow turn (e.g. 117s alert creation) can
be attributed to the specific tool call(s) that dominated it.

Experimental -- not wired into every agentic evaluator yet, just the
plumbing plus visualization (next commit).
…tic)

Wires build_latency_breakdown into both the single-shot VisualizationEvaluator
and the agentic path's RunResult/AgenticEvalOutcome, so detail.latency_breakdown
shows up in eval results for visualization/vis_agentic without any change to
the eval harness's runner or result serialization -- detail already flows
through verbatim.
The prior version only summed tool-call wall time, leaving most of a slow
turn unexplained (e.g. 47s of tool time out of 119s total avg_latency_s).
Timestamps each reasoning step as it streams in (ReasoningStepEvent) and
merges it into the same timeline as tool calls in build_latency_breakdown:
the gap between any two consecutive points -- a tool call starting, a tool
call's result landing, or a reasoning step being emitted -- is charged to
whichever was "active" during it. This accounts for effectively the whole
turn instead of just its tool-call portion.

Also fixes multi-turn accumulation in agentic/visualization.py: each turn's
timestamps restart near 0, so RunResult now shifts them by a running
turn_offset (each turn's own turn_wall_clock_sec) before concatenating --
without it, turn 2's points would overlap turn 1's in the merged timeline.
Reasoning summaries are a full paragraph ("**Title**\n\nlots of detail...");
using the whole thing as a dict key made latency_breakdown unreadable.
Extracts just the bolded title (same convention gdc-mic-ai-evaluation's own
generate_dashboard_summary.py already uses for these reasoning blocks),
falling back to a truncated snippet when a step has no title.
latency_breakdown reasoning labels were fuzzy-matchable to the .reasoning.json
sidecar only by title text -- not reliable, since titles can repeat (two
distinct steps both titled "Considering data analysis"). Each reasoning step
now carries its own 0-based index (same position it occupies in
ChatResult.reasoning_steps and the sidecar's ordered list), embedded directly
in the latency_breakdown label, e.g. "reasoning:3:Evaluating YoY metrics" ->
sidecar block 3. No sidecar format change needed -- the index was always
implicit in list position, just not visible from the latency_breakdown side.

Also fixes a real single-shot-path bug this surfaced: core/runner.py's
_run_one_item took reasoning_steps from whichever run executed LAST, but
best_detail (and any latency_breakdown inside it) from whichever run ranked
BEST -- for K>1 these can be different runs entirely, so the sidecar and
detail.latency_breakdown could each describe a different attempt with no way
to tell. Now both come from the same best-ranked run's chat_result. The
agentic path (core/agentic/visualization.py) already did this correctly via
its own `best` RunResult, so only the single-shot runner needed the fix.
…t-by-name

A dict keyed by "tool:name"/"reasoning:index:title" aggregated repeat calls
of the same tool together and had no way to say what ran before what --
the actual pipeline order was lost. Returns a list of steps instead, each
{"seq", "kind", "name", "index", "duration_s"}: "seq" is the step's real
execution-order position across tools and reasoning combined, "index" is
its position within its own kind's source list (ToolCallEvent.index or
ReasoningStepEvent.index) for looking up the full record -- arguments/result
for a tool call, or the full paragraph in the .reasoning.json sidecar for a
reasoning step. The same tool called twice now produces two separate
entries in their real order, not one summed total.

Also adds ToolCallEvent.index (optional, mirroring the existing
call_ts/result_ts pattern) and re-numbers both tool and reasoning indices
across turns in the agentic visualization path, alongside the existing
turn_offset shift for timestamps.
…cribes

avg_latency_s is a mean across all K runs. detail.latency_breakdown (and
reasoning_steps/the sidecar) only ever describe the single best-ranked run.
For K=1 these coincide, but for K>1 avg_latency_s is not a valid number to
check latency_breakdown's coverage against -- it can describe a run whose
own latency differs substantially from the mean of all K attempts, with no
way to tell by how much. best_run_latency_s is that specific run's own
latency, threaded through core/runner.py (same best_chat_result tracking as
the earlier reasoning-steps fix) and into the JSON report next to
avg_latency_s.
…ators

Extends the visualization-only latency_breakdown work to every enabled
test_kind: agentic_alert_skill, agentic_metric_skill, agentic_guardrail,
agentic_conversation (all multi-turn -- same tool/reasoning index-offset
shift across turns as visualization.py), plus the single-shot
general_question, guardrail, and search_tool evaluators (single chat_result,
no turn accumulation needed).

conversation.py is nested two loops deep (logical turns x clarification
sub-turns) -- added a conversation-wide tool_call_events/reasoning_step_events
accumulator alongside the existing reasoning_steps one, offset-shifted per
physical send_message() call regardless of which loop it's in.

Test fixtures in test_agentic_conversation.py used bare MagicMock() chat
results without call_ts/result_ts/index/reasoning_step_events/
turn_wall_clock_sec set (predating this capture) -- updated them to set
these to their real no-op defaults, matching what an actual un-instrumented
ChatResult already provides.
@coderabbitai

coderabbitai Bot commented Aug 24, 2026

Copy link
Copy Markdown

Warning

Review limit reached

Next included review available in 41 minutes.

View limit details

Limit details: You’ve used the included review currently available.

You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository.

Learn how review limits work.

Review configuration:

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro Plus

Run ID: 721d7fc4-ea2a-4fd3-8815-daba79dbc160

📥 Commits

Reviewing files that changed from the base of the PR and between 9f97835 and 595c98c.

📒 Files selected for processing (20)
  • packages/gooddata-eval/src/gooddata_eval/core/agentic/alert_skill.py
  • packages/gooddata-eval/src/gooddata_eval/core/agentic/conversation.py
  • packages/gooddata-eval/src/gooddata_eval/core/agentic/guardrail.py
  • packages/gooddata-eval/src/gooddata_eval/core/agentic/metric_skill.py
  • packages/gooddata-eval/src/gooddata_eval/core/agentic/visualization.py
  • packages/gooddata-eval/src/gooddata_eval/core/chat/sse_client.py
  • packages/gooddata-eval/src/gooddata_eval/core/evaluators/general_question.py
  • packages/gooddata-eval/src/gooddata_eval/core/evaluators/guardrail.py
  • packages/gooddata-eval/src/gooddata_eval/core/evaluators/search_tool.py
  • packages/gooddata-eval/src/gooddata_eval/core/evaluators/visualization.py
  • packages/gooddata-eval/src/gooddata_eval/core/models.py
  • packages/gooddata-eval/src/gooddata_eval/core/reporting/json_report.py
  • packages/gooddata-eval/src/gooddata_eval/core/runner.py
  • packages/gooddata-eval/tests/test_agentic_alert_skill.py
  • packages/gooddata-eval/tests/test_agentic_conversation.py
  • packages/gooddata-eval/tests/test_agentic_guardrail.py
  • packages/gooddata-eval/tests/test_agentic_metric_skill.py
  • packages/gooddata-eval/tests/test_agentic_visualization.py
  • packages/gooddata-eval/tests/test_runner.py
  • packages/gooddata-eval/tests/test_sse_client.py

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands.

@codecov

codecov Bot commented Aug 24, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 85.52632% with 22 lines in your changes missing coverage. Please review.
✅ Project coverage is 80.61%. Comparing base (9f97835) to head (595c98c).

Files with missing lines Patch % Lines
...eval/src/gooddata_eval/core/agentic/alert_skill.py 78.26% 5 Missing ⚠️
...val/src/gooddata_eval/core/agentic/conversation.py 78.26% 5 Missing ⚠️
...val/src/gooddata_eval/core/agentic/metric_skill.py 78.26% 5 Missing ⚠️
...al/src/gooddata_eval/core/agentic/visualization.py 77.27% 5 Missing ⚠️
...ges/gooddata-eval/src/gooddata_eval/core/runner.py 81.81% 2 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##           master    #1758      +/-   ##
==========================================
+ Coverage   80.59%   80.61%   +0.02%     
==========================================
  Files         272      272              
  Lines       19223    19362     +139     
==========================================
+ Hits        15492    15609     +117     
- Misses       3731     3753      +22     

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Pure whitespace/line-wrap, no functional change -- I'd only run `ruff check`
locally, not `ruff format --check`, which is CI's actual lint-and-format-check
job.
@Tomkess
Tomkess merged commit 0e0f3dd into master Aug 25, 2026
14 checks passed
@Tomkess
Tomkess deleted the feat/tool-call-latency-breakdown branch August 25, 2026 11:13
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants